**** dT 0.000 * top TEST ../../../../bin/vinyltest/tests/o02001.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest **** top extmacro def date(...) **** top extmacro def string(...) **** top extmacro def localhost=127.0.0.1 **** top extmacro def bad_backend=127.0.0.1:41078 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** top extmacro def topbuild=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub **** top extmacro def topsrc=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/../.. **** top macro def testdir=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/../../../../bin/vinyltest/tests **** top macro def tmpdir=/tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952751.0ff2a584 **** top macro def vtcid=vtc.952751.0ff2a584 **** dT 0.001 ** top === vtest "PROXY v2 test on http2" * top VTEST PROXY v2 test on http2 ** top === server s1 { ** s1 Starting server **** s1 macro def s1_addr=127.0.0.1 **** s1 macro def s1_port=47034 **** s1 macro def s1_sock=127.0.0.1:47034 * s1 Listen on 127.0.0.1:47034 ** top === vinyl v1 -proto "PROXY" \ **** dT 0.002 ** s1 Started on 127.0.0.1:47034 (1 iterations) **** dT 0.012 ** v1 Launch *** v1 CMD: cd ${pwd} && exec vinyld -d -n /tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952751.0ff2a584/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0',PROXY -M '127.0.0.1 62317' -P /tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952751.0ff2a584/v1/vinyld.pid -p vmod_path=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: -p feature=+http2 *** v1 CMD: cd /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest && exec vinyld -d -n /tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952751.0ff2a584/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0',PROXY -M '127.0.0.1 62317' -P /tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952751.0ff2a584/v1/vinyld.pid -p vmod_path=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: -p feature=+http2 **** dT 0.014 *** v1 PID: 952761 **** v1 macro def v1_pid=952761 **** v1 macro def v1_name=/tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952751.0ff2a584/v1 **** dT 0.050 *** v1 debug|Warning: mlock() of VSM failed: Not owner (1) **** dT 0.053 *** v1 debug|Debug: Version: vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4 *** v1 debug|Debug: Platform: -jsolaris,-sdefault,-sdefault,-hcritbit *** v1 debug|200 292 *** v1 debug|----------------------------- *** v1 debug|Vinyl Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|-jsolaris,-sdefault,-sdefault,-hcritbit *** v1 debug|vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4 *** v1 debug| *** v1 debug|Type 'help' for command list. *** v1 debug|Type 'quit' to close CLI session. *** v1 debug|Type 'start' to launch worker process. *** v1 debug| **** dT 0.150 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 6 **** dT 0.151 *** v1 CLI RX 107 **** v1 CLI RX|kklflfgvajsosdqofhjsoestjcalyqob **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth d0318320d676ffeda1c59ef02725c91d7e18d45ca3c101e7aeb12c58ac295311 **** dT 0.152 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Vinyl Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|-jsolaris,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4 **** v1 CLI RX| **** v1 CLI RX|Type 'help' for command list. **** v1 CLI RX|Type 'quit' to close CLI session. **** v1 CLI RX|Type 'start' to launch worker process. **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX|backend s1 { .host = "127.0.0.1"; .port = "47034"; } **** v1 CLI TX| **** v1 CLI TX| **** v1 CLI TX|\timport proxy; **** v1 CLI TX|\timport std; **** v1 CLI TX| **** v1 CLI TX|\tacl fwd_client { **** v1 CLI TX|\t\t"1.2.3.4"; **** v1 CLI TX|\t\t"102:304:506::d0e:f10"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|\tacl fwd_server { **** v1 CLI TX|\t\t"5.6.7.8"; **** v1 CLI TX|\t\t"8182:8384:8586::8d8e:8f80"; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|\tsub vcl_deliver { **** v1 CLI TX|\t\tset resp.http.li = local.ip; **** v1 CLI TX|\t\tset resp.http.lp = std.port(local.ip); **** v1 CLI TX|\t\tset resp.http.ri = remote.ip; **** v1 CLI TX|\t\tset resp.http.rp = std.port(remote.ip); **** v1 CLI TX|\t\tset resp.http.ci = client.ip; **** v1 CLI TX|\t\tset resp.http.cp = std.port(client.ip); **** v1 CLI TX|\t\tset resp.http.si = server.ip; **** v1 CLI TX|\t\tset resp.http.sp = std.port(server.ip); **** v1 CLI TX|\t\tset resp.http.fc = (client.ip ~ fwd_client); **** v1 CLI TX|\t\tset resp.http.fs = (server.ip ~ fwd_server); **** v1 CLI TX|\t\tset resp.http.alpn = proxy.alpn(); **** v1 CLI TX|\t\tset resp.http.xport = req.transport; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.252 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.352 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.452 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.553 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.653 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.671 *** v1 CLI RX 200 **** v1 CLI RX|Message from VCC-compiler: **** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged **** v1 CLI RX|Message from C-compiler: **** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged **** v1 CLI RX|cc: Warning: Option -fno-var-tracking-assignments passed to ld, if ld is invoked, ignored otherwise **** v1 CLI RX|"vgc.c", line 3599: warning: statement not reached (E_STATEMENT_NOT_REACHED) **** v1 CLI RX|Message from dlopen: **** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 0.687 *** v1 debug|Debug: Child (952804) Started **** dT 0.716 *** v1 debug|Child launched OK **** dT 0.720 *** v1 CLI RX 200 *** v1 debug|Info: Child (952804) said Child starts *** v1 wait-running **** v1 CLI TX|status *** v1 debug|Info: Child (952804) said notice:\tlibumem was already found to be loaded *** v1 debug|Info: *** v1 debug| Child (952804) said Security: proc_setid missing, uid/gid unchanged *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 41073 **** v1 CLI TX|debug.xid 1000 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 41073 ** v1 Listen on 127.0.0.1 41073 **** v1 macro def v1_addr=127.0.0.1 **** v1 macro def v1_port=41073 **** v1 macro def v1_sock=127.0.0.1:41073 **** v1 macro def v1_a0_addr=127.0.0.1 **** v1 macro def v1_a0_port=41073 **** v1 macro def v1_a0_sock=127.0.0.1:41073 **** dT 0.753 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1773725619.986073/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1773725619.986073/vgc.so" as "vcl1" **** v1 vsl| 0 CLI - Rd vcl.use "vcl1" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd start **** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:41073 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41073 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:41073 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:41073 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:41073 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:41073 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:41073 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:41073 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 41073 **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 41073 **** dT 0.820 ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1000 Proxy "2 local local local local" **** dT 0.821 ** l1 === expect * 1003 ProxyGarbage "PROXY2: bad command \\(2\\)" ** l1 === expect * 1004 ProxyGarbage "PROXY2: Ignoring UNSPEC\\|UNSPEC... ** l1 === expect * 1007 ProxyGarbage "PROXY2: Ignoring unsupported pro... ** l1 === expect * 1010 ProxyGarbage "PROXY2: Ignoring short IPv4 addr... ** l1 === expect * 1013 ProxyGarbage "PROXY2: Ignoring short IPv6 addr... ** l1 === expect * 1016 Proxy "2 1.2.3.4 2314 5.6.7.8 2828" ** l1 === expect * 1019 Proxy "2 102:304:506::d0e:f10 2314 8182:8384:... ** l1 === expect * 1022 Begin "^sess 0 PROXY" ** l1 === expect * 1022 SessClose "^RX_OVERFLOW" ** top === client c1 { ** c1 Starting client **** l1 begin| *** l1 test | expect * 1000 Proxy 2 local local local local ** c1 Waiting for client ** c1 Started on 127.0.0.1:41073 (1 iterations) *** c1 Connect to 127.0.0.1:41073 *** c1 connected fd 21 from 127.0.0.1 47699 to 127.0.0.1:41073 **** dT 0.822 ** c1 === sendhex "0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a" **** c1 sendhex| 0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a ** c1 === sendhex "20 00 00 00" **** c1 sendhex| 20 00 00 00 ** c1 === stream 1 { **** c1 Not in H/2 mode, do what's needed ** c1 === txpri **** c1 txpri|PRI * HTTP/2.0\r **** c1 txpri|\r **** c1 txpri|SM\r **** c1 txpri|\r **** dT 0.831 **** l1 match| 1000 Proxy c 2 local local local local *** l1 test | expect * 1003 ProxyGarbage PROXY2: bad command \\(2\\) **** dT 0.832 ** c1 === stream 0 { ** c1 Starting stream 0 (fffffc7feedc4010) ** c1 Waiting for stream 0 ** c1.0 === txsettings *** c1.0 tx: stream: 0, type: SETTINGS (4), flags: 0x00, size: 0 ** c1.0 === rxsettings *** c1 rx: stream: 0, type: SETTINGS (4), flags: 0x00, size: 18 **** c1.0 settings->MAX_CONCURRENT_STREAMS (3): 100 **** c1.0 settings->INITIAL_WINDOW_SIZE (4): 1048576 **** c1.0 settings->MAX_HEADER_LIST_SIZE (6): 32768 ** c1.0 === txsettings -ack *** c1.0 tx: stream: 0, type: SETTINGS (4), flags: 0x01, size: 0 ** c1.0 === rxsettings *** c1 rx: stream: 0, type: SETTINGS (4), flags: 0x01, size: 0 *** c1 flag: ACK ** c1.0 === expect settings.ack == true **** c1.0 EXPECT settings.ack (true) == "true" match ** c1.0 Ending stream 0 ** c1 Starting stream 1 (fffffc7feedc2010) ** c1 Waiting for stream 1 ** c1.1 === txreq -url /1 **** dT 0.833 *** c1.1 tx: stream: 1, type: HEADERS (1), flags: 0x05, size: 37 ** c1.1 === rxresp **** dT 0.834 *** s1 accepted fd 4 127.0.0.1 47258 ** s1 === rxreq **** s1 rxhdr|GET /1 HTTP/1.1\r **** s1 rxhdr|scheme: http\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Via: 1.1 v1 (Vinyl-Cache/trunk)\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Vinyl: 1002\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|\r **** s1 rxhdrlen = 149 **** s1 http[ 0] |GET **** s1 http[ 1] |/1 **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |scheme: http **** s1 http[ 4] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 5] |Via: 1.1 v1 (Vinyl-Cache/trunk) **** s1 http[ 6] |Accept-Encoding: gzip **** s1 http[ 7] |X-Vinyl: 1002 **** s1 http[ 8] |Host: 127.0.0.1 **** s1 bodylen = 0 ** s1 === expect req.url == "/1" **** s1 EXPECT req.url (/1) == "/1" match ** s1 === expect req.http.x-forwarded-for == "127.0.0.1" **** s1 EXPECT req.http.x-forwarded-for (127.0.0.1) == "127.0.0.1" match ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Tue, 17 Mar 2026 05:33:40 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === rxreq **** dT 0.845 *** c1 rx: stream: 1, type: HEADERS (1), flags: 0x05, size: 234 *** c1 flag: END_STREAM **** c1 header[ 0]: :status: 200 **** c1 header[ 1]: date: Tue, 17 Mar 2026 05:33:40 GMT **** c1 header[ 2]: server: s1 **** c1 header[ 3]: content-length: 0 **** c1 header[ 4]: x-vinyl: 1001 **** c1 header[ 5]: age: 0 **** c1 header[ 6]: via: 1.1 v1 (Vinyl-Cache/trunk) **** c1 header[ 7]: accept-ranges: bytes **** c1 header[ 8]: li: 127.0.0.1 **** c1 header[ 9]: lp: 41073 **** c1 header[10]: ri: 127.0.0.1 **** c1 header[11]: rp: 47699 **** c1 header[12]: ci: 127.0.0.1 **** c1 header[13]: cp: 47699 **** c1 header[14]: si: 127.0.0.1 **** c1 header[15]: sp: 41073 **** c1 header[16]: fc: false **** c1 header[17]: fs: false **** c1 header[18]: alpn: **** c1 header[19]: xport: HTTP/2 ** c1.1 === expect resp.status == 200 **** c1.1 EXPECT resp.status (200) == "200" match ** c1.1 === expect resp.http.si == "127.0.0.1" **** c1.1 EXPECT resp.http.si (127.0.0.1) == "127.0.0.1" match ** c1.1 === expect resp.http.sp == "41073" **** c1.1 EXPECT resp.http.sp (41073) == "41073" match ** c1.1 === expect resp.http.ci == "127.0.0.1" **** c1.1 EXPECT resp.http.ci (127.0.0.1) == "127.0.0.1" match ** c1.1 === expect resp.http.xport == "HTTP/2" **** c1.1 EXPECT resp.http.xport (HTTP/2) == "HTTP/2" match ** c1.1 Ending stream 1 *** c1 closing fd 21 ** c1 Ending ** top === delay .1 *** top delaying 0.1 second(s) **** dT 0.853 **** v1 vsl| 1000 Begin c sess 0 PROXY **** v1 vsl| 1000 SessOpen c 127.0.0.1 47699 a0 127.0.0.1 41073 1773725620.655269 16 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:41073 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41073 **** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1000 Proxy c 2 local local local local **** v1 vsl| 1000 Debug c H2 Prior Knowledge Upgrade **** v1 vsl| 1000 Link c req 1001 rxreq **** v1 vsl| 1002 Begin b bereq 1001 fetch **** v1 vsl| 1002 VCL_use b vcl1 **** v1 vsl| 1002 Timestamp b Start: 1773725620.667225 0.000000 0.000000 **** v1 vsl| 1002 BereqMethod b GET **** v1 vsl| 1002 BereqURL b /1 **** v1 vsl| 1002 BereqProtocol b HTTP/2.0 **** v1 vsl| 1002 BereqHeader b scheme: http **** v1 vsl| 1002 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1002 BereqHeader b Via: 1.1 v1 (Vinyl-Cache/trunk) **** v1 vsl| 1002 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1002 BereqProtocol b HTTP/1.1 **** v1 vsl| 1002 BereqHeader b X-Vinyl: 1002 **** v1 vsl| 1002 VCL_call b BACKEND_FETCH **** v1 vsl| 1002 VCL_return b fetch **** v1 vsl| 1002 Timestamp b Fetch: 1773725620.667280 0.000055 0.000055 **** v1 vsl| 1002 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1002 Timestamp b Connected: 1773725620.667408 0.000182 0.000127 **** v1 vsl| 1002 BackendOpen b 19 s1 127.0.0.1 47034 127.0.0.1 47258 connect **** v1 vsl| 1002 Timestamp b Bereq: 1773725620.667500 0.000275 0.000092 **** v1 vsl| 1002 BerespProtocol b HTTP/1.1 **** v1 vsl| 1002 BerespStatus b 200 **** v1 vsl| 1002 BerespReason b OK **** v1 vsl| 1002 BerespHeader b Date: Tue, 17 Mar 2026 05:33:40 GMT **** v1 vsl| 1002 BerespHeader b Server: s1 **** v1 vsl| 1002 BerespHeader b Content-Length: 0 **** v1 vsl| 1002 Timestamp b Beresp: 1773725620.668080 0.000855 0.000580 **** v1 vsl| 1002 TTL b RFC 120 10 0 1773725621 1773725621 1773725620 0 0 cacheable **** v1 vsl| 1002 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1002 VCL_return b deliver **** v1 vsl| 1002 Debug b Missing content-range header or unknown range unit **** v1 vsl| 1002 Timestamp b Process: 1773725620.668165 0.000939 0.000084 **** v1 vsl| 1002 Filters b **** v1 vsl| 1002 Storage b umem s0 **** v1 vsl| 1002 Fetch_Body b 0 none - **** v1 vsl| 1002 BackendClose b 19 s1 recycle **** v1 vsl| 1002 Timestamp b BerespBody: 1773725620.678299 0.011073 0.010133 **** v1 vsl| 1002 Length b 0 **** v1 vsl| 1002 BereqAcct b 149 0 149 87 0 87 **** v1 vsl| 1002 End b **** v1 vsl| 1001 Begin c req 1000 rxreq **** v1 vsl| 1001 Timestamp c Start: 1773725620.665901 0.000000 0.000000 **** v1 vsl| 1001 ReqProtocol c HTTP/2.0 **** v1 vsl| 1001 Timestamp c Req: 1773725620.666530 0.000628 0.000628 **** v1 vsl| 1001 VCL_use c vcl1 **** v1 vsl| 1001 ReqStart c 127.0.0.1 47699 a0 **** v1 vsl| 1001 ReqMethod c GET **** v1 vsl| 1001 ReqURL c /1 **** v1 vsl| 1001 ReqProtocol c HTTP/2.0 **** v1 vsl| 1001 ReqHeader c scheme: http **** v1 vsl| 1001 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1001 ReqHeader c Via: 1.1 v1 (Vinyl-Cache/trunk) **** v1 vsl| 1001 VCL_call c RECV **** v1 vsl| 1001 VCL_return c hash **** v1 vsl| 1001 VCL_call c HASH **** v1 vsl| 1001 VCL_return c lookup **** v1 vsl| 1001 VCL_call c MISS **** v1 vsl| 1001 VCL_return c fetch **** v1 vsl| 1001 Link c bereq 1002 fetch **** v1 vsl| 1001 Timestamp c Fetch: 1773725620.678308 0.012406 0.011777 **** v1 vsl| 1001 RespProtocol c HTTP/1.1 **** v1 vsl| 1001 RespStatus c 200 **** v1 vsl| 1001 RespReason c OK **** v1 vsl| 1001 RespHeader c Date: Tue, 17 Mar 2026 05:33:40 GMT **** v1 vsl| 1001 RespHeader c Server: s1 **** v1 vsl| 1001 RespHeader c Content-Length: 0 **** v1 vsl| 1001 RespHeader c X-Vinyl: 1001 **** v1 vsl| 1001 RespHeader c Age: 0 **** v1 vsl| 1001 RespHeader c Via: 1.1 v1 (Vinyl-Cache/trunk) **** v1 vsl| 1001 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1001 VCL_call c DELIVER **** v1 vsl| 1001 RespHeader c li: 127.0.0.1 **** v1 vsl| 1001 RespHeader c lp: 41073 **** v1 vsl| 1001 RespHeader c ri: 127.0.0.1 **** v1 vsl| 1001 RespHeader c rp: 47699 **** v1 vsl| 1001 RespHeader c ci: 127.0.0.1 **** v1 vsl| 1001 RespHeader c cp: 47699 **** v1 vsl| 1001 RespHeader c si: 127.0.0.1 **** v1 vsl| 1001 RespHeader c sp: 41073 **** v1 vsl| 1001 RespHeader c fc: false **** v1 vsl| 1001 RespHeader c fs: false **** v1 vsl| 1001 RespHeader c alpn: **** v1 vsl| 1001 RespHeader c xport: HTTP/2 **** v1 vsl| 1001 VCL_return c deliver **** v1 vsl| 1001 Timestamp c Process: 1773725620.678475 0.012573 0.000166 **** v1 vsl| 1001 Filters c **** v1 vsl| 1001 RespProtocol c HTTP/2.0 **** v1 vsl| 1001 Debug c HP {33, "date:", ""} **** v1 vsl| 1001 Debug c HP {54, "server:", ""} **** v1 vsl| 1001 Debug c HP {28, "content-length:", ""} **** v1 vsl| 1001 Debug c HP {21, "age:", ""} **** v1 vsl| 1001 Debug c HP {60, "via:", ""} **** v1 vsl| 1001 Debug c HP {18, "accept-ranges:", ""} **** v1 vsl| 1001 Timestamp c Resp: 1773725620.678600 0.012698 0.000125 **** v1 vsl| 1001 ReqAcct c 37 0 37 234 0 234 **** v1 vsl| 1001 End c **** dT 0.945 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client **** dT 0.946 ** c1 Started on 127.0.0.1:41073 (1 iterations) *** c1 Connect to 127.0.0.1:41073 *** c1 connected fd 21 from 127.0.0.1 45114 to 127.0.0.1:41073 ** c1 === sendhex "0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a" **** c1 sendhex| 0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a ** c1 === sendhex "22 00 00 00" **** c1 sendhex| 22 00 00 00 ** c1 === timeout 8 ** c1 === expect_close **** c1 Expecting close (fd = 21) **** c1 fd=21 EOF, as expected *** c1 closing fd 21 ** c1 Ending ** top === delay .1 *** top delaying 0.1 second(s) **** dT 0.951 **** l1 match| 1003 ProxyGarbage c PROXY2: bad command (2) *** l1 test | expect * 1004 ProxyGarbage PROXY2: Ignoring UNSPEC\\|UNSPEC addresses **** dT 0.953 **** v1 vsl| 1000 Debug c H2: Got pu PRISM **** v1 vsl| 1000 H2RxHdr c [000000040000000000] **** v1 vsl| 1000 Debug c H2RXF SETTINGS[0] 0x00 0x00000000 **** dT 0.954 **** v1 vsl| 1000 H2RxHdr c [000000040100000000] **** v1 vsl| 1000 Debug c H2RXF SETTINGS[0] 0x01 0x00000000 **** v1 vsl| 1000 H2RxHdr c [000025010500000001] **** v1 vsl| 1000 H2RxBody c [00053a70617468022f3100073a6d6574686f640347455400073a736368656d650468747470] **** v1 vsl| 1000 Debug c H2RXF HEADERS[37] 0x05 0x00000001 0x00053a70617468022f3100073a6d6574686f640347455400073a736368656d650468747470 **** v1 vsl| 1000 Debug c H2: HTC eof (Unexpected end of input) frame=complete goaway=0 **** v1 vsl| 1000 Debug c H2 CLEANUP H2CE_NO_ERROR **** v1 vsl| 1000 Debug c KILL st=1 state=6 sched=0 **** v1 vsl| 1000 Debug c ST 0 0 **** v1 vsl| 1000 ReqAcct c 27 0 27 36 26 62 **** v1 vsl| 1000 SessClose c REM_CLOSE 0.124 **** v1 vsl| 1000 End c **** v1 vsl| 1003 Begin c sess 0 PROXY **** v1 vsl| 1003 SessOpen c 127.0.0.1 45114 a0 127.0.0.1 41073 1773725620.779460 17 **** v1 vsl| 1003 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1003 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41073 **** v1 vsl| 1003 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1003 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1003 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1003 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1003 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1003 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1003 ProxyGarbage c PROXY2: bad command (2) **** v1 vsl| 1003 SessClose c RX_JUNK 0.000 **** v1 vsl| 1003 End c **** dT 1.046 ** top === client c1 { ** c1 Starting client ** c1 Waiting for client ** c1 Started on 127.0.0.1:41073 (1 iterations) *** c1 Connect to 127.0.0.1:41073 *** c1 connected fd 21 from 127.0.0.1 59240 to 127.0.0.1:41073 ** c1 === sendhex "0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a" **** c1 sendhex| 0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a ** c1 === sendhex "21 00 00 00" **** c1 sendhex| 21 00 00 00 ** c1 === stream 1 { **** c1 Not in H/2 mode, do what's needed ** c1 === txpri **** c1 txpri|PRI * HTTP/2.0\r **** c1 txpri|\r **** c1 txpri|SM\r **** c1 txpri|\r **** dT 1.052 **** l1 match| 1004 ProxyGarbage c PROXY2: Ignoring UNSPEC|UNSPEC addresses *** l1 test | expect * 1007 ProxyGarbage PROXY2: Ignoring unsupported protocol \\(0x99\\) **** dT 1.054 **** v1 vsl| 1004 Begin c sess 0 PROXY **** v1 vsl| 1004 SessOpen c 127.0.0.1 59240 a0 127.0.0.1 41073 1773725620.880109 18 **** v1 vsl| 1004 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1004 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41073 **** v1 vsl| 1004 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1004 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1004 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1004 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1004 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1004 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1004 ProxyGarbage c PROXY2: Ignoring UNSPEC|UNSPEC addresses **** dT 1.057 ** c1 === stream 0 { ** c1 Starting stream 0 (fffffc7feedc0010) ** c1 Waiting for stream 0 ** c1.0 === txsettings *** c1.0 tx: stream: 0, type: SETTINGS (4), flags: 0x00, size: 0 ** c1.0 === rxsettings *** c1 rx: stream: 0, type: SETTINGS (4), flags: 0x00, size: 18 **** c1.0 settings->MAX_CONCURRENT_STREAMS (3): 100 **** c1.0 settings->INITIAL_WINDOW_SIZE (4): 1048576 **** c1.0 settings->MAX_HEADER_LIST_SIZE (6): 32768 ** c1.0 === txsettings -ack *** c1.0 tx: stream: 0, type: SETTINGS (4), flags: 0x01, size: 0 ** c1.0 === rxsettings *** c1 rx: stream: 0, type: SETTINGS (4), flags: 0x01, size: 0 *** c1 flag: ACK ** c1.0 === expect settings.ack == true **** c1.0 EXPECT settings.ack (true) == "true" match ** c1.0 Ending stream 0 ** c1 Starting stream 1 (fffffc7feedbe010) ** c1 Waiting for stream 1 ** c1.1 === txreq -url /2 *** c1.1 tx: stream: 1, type: HEADERS (1), flags: 0x05, size: 37 ** c1.1 === rxresp **** dT 1.058 **** s1 rxhdr|GET /2 HTTP/1.1\r **** s1 rxhdr|scheme: http\r **** s1 rxhdr|X-Forwarded-For: 127.0.0.1\r **** s1 rxhdr|Via: 1.1 v1 (Vinyl-Cache/trunk)\r **** s1 rxhdr|Accept-Encoding: gzip\r **** s1 rxhdr|X-Vinyl: 1006\r **** s1 rxhdr|Host: 127.0.0.1\r **** s1 rxhdr|\r **** s1 rxhdrlen = 149 **** s1 http[ 0] |GET **** s1 http[ 1] |/2 **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |scheme: http **** s1 http[ 4] |X-Forwarded-For: 127.0.0.1 **** s1 http[ 5] |Via: 1.1 v1 (Vinyl-Cache/trunk) **** s1 http[ 6] |Accept-Encoding: gzip **** s1 http[ 7] |X-Vinyl: 1006 **** s1 http[ 8] |Host: 127.0.0.1 **** s1 bodylen = 0 ** s1 === expect req.url == "/2" **** s1 EXPECT req.url (/2) == "/2" match ** s1 === expect req.http.x-forwarded-for == "127.0.0.1" **** s1 EXPECT req.http.x-forwarded-for (127.0.0.1) == "127.0.0.1" match ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Tue, 17 Mar 2026 05:33:40 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === rxreq **** dT 1.068 *** c1 rx: stream: 1, type: HEADERS (1), flags: 0x05, size: 234 *** c1 flag: END_STREAM **** c1 header[ 0]: :status: 200 **** c1 header[ 1]: date: Tue, 17 Mar 2026 05:33:40 GMT **** c1 header[ 2]: server: s1 **** c1 header[ 3]: content-length: 0 **** c1 header[ 4]: x-vinyl: 1005 **** c1 header[ 5]: age: 0 **** c1 header[ 6]: via: 1.1 v1 (Vinyl-Cache/trunk) **** c1 header[ 7]: accept-ranges: bytes **** c1 header[ 8]: li: 127.0.0.1 **** c1 header[ 9]: lp: 41073 **** c1 header[10]: ri: 127.0.0.1 **** c1 header[11]: rp: 59240 **** c1 header[12]: ci: 127.0.0.1 **** c1 header[13]: cp: 59240 **** c1 header[14]: si: 127.0.0.1 **** c1 header[15]: sp: 41073 **** c1 header[16]: fc: false **** c1 header[17]: fs: false **** c1 header[18]: alpn: **** c1 header[19]: xport: HTTP/2 ** c1.1 === expect resp.status == 200 **** c1.1 EXPECT resp.status (200) == "200" match ** c1.1 === expect resp.http.si == "127.0.0.1" **** c1.1 EXPECT resp.http.si (127.0.0.1) == "127.0.0.1" match ** c1.1 === expect resp.http.sp == "41073" **** c1.1 EXPECT resp.http.sp (41073) == "41073" match ** c1.1 === expect resp.http.ci == "127.0.0.1" **** c1.1 EXPECT resp.http.ci (127.0.0.1) == "127.0.0.1" match ** c1.1 === expect resp.http.xport == "HTTP/2" **** c1.1 EXPECT resp.http.xport (HTTP/2) == "HTTP/2" match ** c1.1 Ending stream 1 *** c1 closing fd 21 ** c1 Ending ** top === delay .1 *** top delaying 0.1 second(s) **** dT 1.154 **** v1 vsl| 1004 Debug c H2 Prior Knowledge Upgrade **** v1 vsl| 1004 Link c req 1005 rxreq **** v1 vsl| 1006 Begin b bereq 1005 fetch **** v1 vsl| 1006 VCL_use b vcl1 **** v1 vsl| 1006 Timestamp b Start: 1773725620.890996 0.000000 0.000000 **** v1 vsl| 1006 BereqMethod b GET **** v1 vsl| 1006 BereqURL b /2 **** v1 vsl| 1006 BereqProtocol b HTTP/2.0 **** v1 vsl| 1006 BereqHeader b scheme: http **** v1 vsl| 1006 BereqHeader b X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1006 BereqHeader b Via: 1.1 v1 (Vinyl-Cache/trunk) **** v1 vsl| 1006 BereqHeader b Accept-Encoding: gzip **** v1 vsl| 1006 BereqProtocol b HTTP/1.1 **** v1 vsl| 1006 BereqHeader b X-Vinyl: 1006 **** v1 vsl| 1006 VCL_call b BACKEND_FETCH **** v1 vsl| 1006 VCL_return b fetch **** v1 vsl| 1006 Timestamp b Fetch: 1773725620.891023 0.000026 0.000026 **** v1 vsl| 1006 BereqHeader b Host: 127.0.0.1 **** v1 vsl| 1006 Timestamp b Connected: 1773725620.891036 0.000039 0.000012 **** v1 vsl| 1006 BackendOpen b 19 s1 127.0.0.1 47034 127.0.0.1 47258 reuse 0.223647 1 **** v1 vsl| 1006 Timestamp b Bereq: 1773725620.891075 0.000078 0.000039 **** v1 vsl| 1006 BerespProtocol b HTTP/1.1 **** v1 vsl| 1006 BerespStatus b 200 **** v1 vsl| 1006 BerespReason b OK **** v1 vsl| 1006 BerespHeader b Date: Tue, 17 Mar 2026 05:33:40 GMT **** v1 vsl| 1006 BerespHeader b Server: s1 **** v1 vsl| 1006 BerespHeader b Content-Length: 0 **** v1 vsl| 1006 Timestamp b Beresp: 1773725620.891571 0.000575 0.000496 **** v1 vsl| 1006 TTL b RFC 120 10 0 1773725621 1773725621 1773725620 0 0 cacheable **** v1 vsl| 1006 VCL_call b BACKEND_RESPONSE **** v1 vsl| 1006 VCL_return b deliver **** v1 vsl| 1006 Debug b Missing content-range header or unknown range unit **** v1 vsl| 1006 Timestamp b Process: 1773725620.891595 0.000599 0.000024 **** v1 vsl| 1006 Filters b **** v1 vsl| 1006 Storage b umem s0 **** v1 vsl| 1006 Fetch_Body b 0 none - **** v1 vsl| 1006 BackendClose b 19 s1 recycle **** v1 vsl| 1006 Timestamp b BerespBody: 1773725620.901656 0.010659 0.010060 **** v1 vsl| 1006 Length b 0 **** v1 vsl| 1006 BereqAcct b 149 0 149 87 0 87 **** v1 vsl| 1006 End b **** v1 vsl| 1005 Begin c req 1004 rxreq **** v1 vsl| 1005 Timestamp c Start: 1773725620.890498 0.000000 0.000000 **** v1 vsl| 1005 ReqProtocol c HTTP/2.0 **** v1 vsl| 1005 Timestamp c Req: 1773725620.890872 0.000373 0.000373 **** v1 vsl| 1005 VCL_use c vcl1 **** v1 vsl| 1005 ReqStart c 127.0.0.1 59240 a0 **** v1 vsl| 1005 ReqMethod c GET **** v1 vsl| 1005 ReqURL c /2 **** v1 vsl| 1005 ReqProtocol c HTTP/2.0 **** v1 vsl| 1005 ReqHeader c scheme: http **** v1 vsl| 1005 ReqHeader c X-Forwarded-For: 127.0.0.1 **** v1 vsl| 1005 ReqHeader c Via: 1.1 v1 (Vinyl-Cache/trunk) **** v1 vsl| 1005 VCL_call c RECV **** v1 vsl| 1005 VCL_return c hash **** v1 vsl| 1005 VCL_call c HASH **** v1 vsl| 1005 VCL_return c lookup **** v1 vsl| 1005 VCL_call c MISS **** v1 vsl| 1005 VCL_return c fetch **** v1 vsl| 1005 Link c bereq 1006 fetch **** v1 vsl| 1005 Timestamp c Fetch: 1773725620.901663 0.011165 0.010791 **** v1 vsl| 1005 RespProtocol c HTTP/1.1 **** v1 vsl| 1005 RespStatus c 200 **** v1 vsl| 1005 RespReason c OK **** v1 vsl| 1005 RespHeader c Date: Tue, 17 Mar 2026 05:33:40 GMT **** v1 vsl| 1005 RespHeader c Server: s1 **** v1 vsl| 1005 RespHeader c Content-Length: 0 **** v1 vsl| 1005 RespHeader c X-Vinyl: 1005 **** v1 vsl| 1005 RespHeader c Age: 0 **** v1 vsl| 1005 RespHeader c Via: 1.1 v1 (Vinyl-Cache/trunk) **** v1 vsl| 1005 RespHeader c Accept-Ranges: bytes **** v1 vsl| 1005 VCL_call c DELIVER **** v1 vsl| 1005 RespHeader c li: 127.0.0.1 **** v1 vsl| 1005 RespHeader c lp: 41073 **** v1 vsl| 1005 RespHeader c ri: 127.0.0.1 **** v1 vsl| 1005 RespHeader c rp: 59240 **** v1 vsl| 1005 RespHeader c ci: 127.0.0.1 **** v1 vsl| 1005 RespHeader c cp: 59240 **** v1 vsl| 1005 RespHeader c si: 127.0.0.1 **** v1 vsl| 1005 RespHeader c sp: 41073 **** v1 vsl| 1005 RespHeader c fc: false **** v1 vsl| 1005 RespHeader c fs: false **** v1 vsl| 1005 RespHeader c alpn: **** v1 vsl| 1005 RespHeader c xport: HTTP/2 **** v1 vsl| 1005 VCL_return c deliver **** v1 vsl| 1005 Timestamp c Process: 1773725620.901720 0.011221 0.000056 **** v1 vsl| 1005 Filters c **** v1 vsl| 1005 RespProtocol c HTTP/2.0 **** v1 vsl| 1005 Debug c HP {33, "date:", ""} **** v1 vsl| 1005 Debug c HP {54, "server:", ""} **** v1 vsl| 1005 Debug c HP {28, "content-length:", ""} **** v1 vsl| 1005 Debug c HP {21, "age:", ""} **** v1 vsl| 1005 Debug c HP {60, "via:", ""} **** v1 vsl| 1005 Debug c HP {18, "accept-ranges:", ""} **** v1 vsl| 1005 Timestamp c Resp: 1773725620.901766 0.011267 0.000046 **** v1 vsl| 1005 ReqAcct c 37 0 37 234 0 234 **** v1 vsl| 1005 End c **** dT 1.168 ** top === client c1 { ** c1 Starting client **** dT 1.169 ** c1 Waiting for client ** c1 Started on 127.0.0.1:41073 (1 iterations) *** c1 Connect to 127.0.0.1:41073 *** c1 connected fd 21 from 127.0.0.1 40807 to 127.0.0.1:41073 ** c1 === sendhex "0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a" **** c1 sendhex| 0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a ** c1 === sendhex "21 99 00 00" **** c1 sendhex| 21 99 00 00 ** c1 === stream 1 { **** c1 Not in H/2 mode, do what's needed ** c1 === txpri **** c1 txpri|PRI * HTTP/2.0\r **** c1 txpri|\r **** c1 txpri|SM\r **** c1 txpri|\r **** dT 1.172 **** l1 match| 1007 ProxyGarbage c PROXY2: Ignoring unsupported protocol (0x99) *** l1 test | expect * 1010 ProxyGarbage PROXY2: Ignoring short IPv4 addresses \\(11\\) **** dT 1.180 ** c1 === stream 0 { ** c1 Starting stream 0 (fffffc7feedbc010) **** dT 1.181 ---- c1.0 Assert error in stream_start(), ../../../../bin/vinyltest/vtest2/src/vtc_http2.c line 2738: Condition(pthread_create(&s->tp, ((void *)0), stream_thread, s) failed) not true. Errno=11 Resource temporarily unavailable Backtrace: fffffc5e88602b7d: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'vbt_execinfo+0x3d [0xfffffc5e88602b7d] fffffc5e88602f21: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VBT_format+0x41 [0xfffffc5e88602f21] fffffc5e88602fd0: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VBT_dump+0x90 [0xfffffc5e88602fd0] 47162d: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'vtc_log_VAS_Fail+0xcd [0x47162d] fffffc5e886014ac: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VAS_Fail+0x8c [0xfffffc5e886014ac] 46dc6b: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'stream_start+0x18b [0x46dc6b] 46e03b: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'stream_run+0x1b [0x46e03b] 46e380: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'cmd_stream+0x320 [0x46e380] 4578e8: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'cmd_http_stream+0x1c8 [0x4578e8] 437c5a: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'parse_string+0x11da [0x437c5a] 4578ce: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'cmd_http_stream+0x1ae [0x4578ce] 437c5a: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'parse_string+0x11da [0x437c5a] 458722: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'http_process+0x8c2 [0x458722] 48f25b: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'sess_process+0x13b [0x48f25b] 48f63f: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'sess_thread+0x3bf [0x48f63f] fffffc7fef2356e7: /lib/amd64/libc.so.1'_thrp_setup+0x77 [0xfffffc7fef2356e7] fffffc7fef235a30: /lib/amd64/libc.so.1'_lwp_start+0x0 [0xfffffc7fef235a30] * top Aborting execution, test failed * top RESETTING after ../../../../bin/vinyltest/tests/o02001.vtc ** s1 Waiting for server (3/-1) ** v1 Wait **** v1 CLI TX|panic.show *** v1 CLI RX 300 **** v1 CLI RX|Child has not panicked or panic has been cleared *** v1 debug|Info: manager stopping child *** v1 debug|Debug: Stopping Child **** dT 1.182 ---- l1 bad | outstanding expectations **** dT 1.254 **** v1 vsl| 1004 Debug c H2: Got pu PRISM **** v1 vsl| 1004 H2RxHdr c [000000040000000000] **** v1 vsl| 1004 Debug c H2RXF SETTINGS[0] 0x00 0x00000000 **** v1 vsl| 1004 H2RxHdr c [000000040100000000] **** v1 vsl| 1004 Debug c H2RXF SETTINGS[0] 0x01 0x00000000 **** v1 vsl| 1004 H2RxHdr c [000025010500000001] **** v1 vsl| 1004 H2RxBody c [00053a70617468022f3200073a6d6574686f640347455400073a736368656d650468747470] **** v1 vsl| 1004 Debug c H2RXF HEADERS[37] 0x05 0x00000001 0x00053a70617468022f3200073a6d6574686f640347455400073a736368656d650468747470 **** v1 vsl| 1004 Debug c H2: HTC eof (Unexpected end of input) frame=complete goaway=0 **** v1 vsl| 1004 Debug c H2 CLEANUP H2CE_NO_ERROR **** v1 vsl| 1004 Debug c KILL st=1 state=6 sched=0 **** v1 vsl| 1004 Debug c ST 0 0 **** v1 vsl| 1004 ReqAcct c 27 0 27 36 26 62 **** v1 vsl| 1004 SessClose c REM_CLOSE 0.122 **** v1 vsl| 1004 End c **** v1 vsl| 1007 Begin c sess 0 PROXY **** v1 vsl| 1007 SessOpen c 127.0.0.1 40807 a0 127.0.0.1 41073 1773725621.002882 16 **** v1 vsl| 1007 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1007 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41073 **** v1 vsl| 1007 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1007 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1007 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1007 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1007 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1007 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:41073 **** v1 vsl| 1007 ProxyGarbage c PROXY2: Ignoring unsupported protocol (0x99) **** v1 vsl| 1007 Debug c H2 Prior Knowledge Upgrade **** v1 vsl| 1007 Debug c H2: Got pu PRISM **** v1 vsl| 1007 Debug c H2: HTC eof (Unexpected end of input) frame=complete goaway=0 **** v1 vsl| 1007 Debug c H2 CLEANUP H2CE_NO_ERROR **** v1 vsl| 1007 ReqAcct c 0 0 0 18 26 44 **** v1 vsl| 1007 SessClose c REM_CLOSE 0.012 **** v1 vsl| 1007 End c **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 2.182 *** v1 debug|Info: Child (952804) said shutdown waiting for 1 reference on vcl1 **** dT 2.282 *** v1 debug|Info: Child (952804) said Child dies *** v1 debug|Info: Child (952804) ended *** v1 debug|Debug: Child cleanup complete *** v1 debug| *** v1 debug|Info: manager dies *** v1 debug| **** dT 2.283 **** v1 STDOUT EOF **** dT 2.355 ** v1 WAIT4 pid=952761 status=0x0000 (user 0.737000 sys 0.261000) ** l1 Waiting for logexp * top TEST ../../../../bin/vinyltest/tests/o02001.vtc FAILED # top TEST ../../../../bin/vinyltest/tests/o02001.vtc FAILED (2.361) exit=2 FAIL tests/o02001.vtc (exit status: 2)